Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

sql/event_log: reduce tech debt, simplify and fix bugs #64894

Merged
merged 8 commits into from
May 21, 2021

Conversation

knz
Copy link
Contributor

@knz knz commented May 7, 2021

Fixes #64685.
First commit from #64871.

Prior to this patch, there was a little mess in sql/event_log.go
that had been introduced when "optimizing" GRANT/REVOKE to only
use one write batch for all the events logged:

  • a lot of code had been duplicated;
  • the control flow had been rendered more complex;
  • the API interface for the functions in event_log.go
    were complex to use, requiring callers to provide descriptor
    IDs and structured events as separate slices;
  • the optimizing logic was not properly applied to the
    other case where multiple events are emitted:
    SQL audit logging in exec_log.go.

This patch streamlines this by reducing event_log.go back to its
simpler form: an overall event refinement pipeline with a
straightforward control flow.

To guide future maintainers, the patch also adds an explanatory
comment at the top of the file that sketches the overall structure of
the pipeline.

Finally, this patch fixes a bug introduced when query logging
started using structured events: the ability to automatically
copy all the execution events to the DEV channel when
setting the vmodule setting to exec_log=2 (or above).

In addition to fixing that bug, the following new vmodule-based
abilities are added:

  • events for DDL statements and others that call logEvent() can now
    be collected in the DEV channel by using the name of the source file
    where they were generated as filter (e.g. vmodule=create_table=2 for
    the CREATE TABLE events.
  • events of other kinds can be collected in the DEV channel
    by setting vmodule=event_log=2.

(Note a subtle difference between vmodule=create_table=2 and
vmodule=exec_log=2: the former emits the event to the DEV channel
while the stmt is executed; the latter emits the event after the stmt
completes. If both are enabled, TWO events are sent to the DEV channel.)

Since all the vmodule filtering options are subject to change without
notice between versions, we do not wish to document these nuances.
For this reason, the release note below is left blank.

Release note: None

@knz knz requested review from rafiss and RichardJCai May 7, 2021 20:41
@cockroach-teamcity
Copy link
Member

This change is Reviewable

@knz knz force-pushed the 20210507-event-log branch 4 times, most recently from 64a534e to 4b24c96 Compare May 8, 2021 12:20
Copy link
Collaborator

@rafiss rafiss left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

so far i wasn't able to follow the code enough to identify where the fix to log the query string in exec_log happens. in general, the comments and refactors look good to me.

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @RichardJCai)

@knz
Copy link
Contributor Author

knz commented May 13, 2021

so far i wasn't able to follow the code enough to identify where the fix to log the query string in exec_log happens

it was a mistake to do if logV { log.VEventf(...) } in exec_log.go because at that point the structured payload is not fully populated yet. This population occurs in the pipeline described at the top of event_log.go.

So instead the log.V case is handled differently: if logStmt || logV { logEvent(...) } and then deeper inside the pipeline (inside insertEventRecords()) we check log.V again to do the thing at that point.

Does this explain?

@knz knz force-pushed the 20210507-event-log branch from 4b24c96 to c8b0ab2 Compare May 14, 2021 14:23
Copy link
Contributor Author

@knz knz left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I have rewritten the PR to decompose each logical change into a sub-commit, for your reviewing pleasure. I hope you like it?

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @RichardJCai)

Copy link
Collaborator

@rafiss rafiss left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

sorry i missed your updates while i was out of office at the end of last week. yes, this does help and it was pleasurable to review! lgtm

Reviewed 1 of 4 files at r1, 5 of 5 files at r8.
Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @RichardJCai)

knz added 8 commits May 21, 2021 11:02
Prior to this patch, there was a little mess in `sql/event_log.go`
that had been introduced when "optimizing" GRANT/REVOKE to only
use one write batch for all the events logged:

- the API interface for the functions in event_log.go
  were complex to use, requiring callers to provide descriptor
  IDs and structured events as separate slices;
- the optimizing logic was not properly applied to the
  other case where multiple events are emitted:
  SQL audit logging in `exec_log.go`.

This patch cleans this up by using the same struct `eventLogEntry` as
argument to the various APIs.

Release note: None
…ging

The previous patch to batch event writes for GRANT/REVOKE had
duplicated code. This was not necessary. This patch fixes this by
using the same code for both cases.

Release note: None
This clarifies its purpose.

Release note: None
`logEventsOnlyExternally()` is specific to the code in `exec_log.go`
and should thus reside there. This patch achieves that.

Release note: None
The code was previously using two booleans `onlyLog` and
`writeToEventLog` which were making the code difficult to understand
and to maintain.

This patch fixes this by introducing a bitset with descriptive names.

Release note: None
This further simplifies the internal API.

Release note: None
This patch describes `event_log.go` at a high level: an overall event
refinement pipeline with a straightforward control flow.

Release note: None
This patch fixes a bug introduced when query logging
started using structured events: the ability to automatically
copy all the execution events to the DEV channel when
setting the `vmodule` setting to `exec_log=2` (or above).

In addition to fixing that bug, the following new vmodule-based
abilities are added:

- events for DDL statements and others that call `logEvent()` can now
  be collected in the DEV channel by using the name of the source file
  where they were generated as filter (e.g. `vmodule=create_table=2` for
  the CREATE TABLE events.
- events of other kinds can be collected in the DEV channel
  by setting `vmodule=event_log=2`.

(Note a subtle difference between `vmodule=create_table=2` and
`vmodule=exec_log=2`: the former emits the event to the DEV channel
while the stmt is executed; the latter emits the event after the stmt
completes. If both are enabled, TWO events are sent to the DEV channel.)

Since all the vmodule filtering options are subject to change without
notice between versions, we do not wish to document these nuances.
For this reason, the release note below is left blank.

Release note: None
@knz
Copy link
Contributor Author

knz commented May 21, 2021

TFYR!

bors r=rafiss

@craig
Copy link
Contributor

craig bot commented May 21, 2021

Build succeeded:

@craig craig bot merged commit 303f766 into cockroachdb:master May 21, 2021
@knz knz deleted the 20210507-event-log branch May 21, 2021 10:26
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

exec_log: --vmodule=exec_log=2 does not log SQL query strings
3 participants